mysql

推荐列表 站点导航

当前位置:首页 > 数据库 > mysql >

MySQL DeadLock故障排查全过程记录

来源:网络整理  作者:网络  发布时间:2020-12-09 19:13
【作者】 刘博:携程技术保障中心数据库高级经理,主要关注Sql server和Mysql的运维和故障处理。 【环境】 版本号:...
0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eea14; asc

持有的锁信息为:

登录Mysql服务器查看日志:

可以看到485 SEK这两个资源形成了一个环状,最终发生死锁。

Using intersect(column5_index,idxColumn6)

从5.1开始,引入了 index merge 优化技术,对同一个表可以使用多个索引分别进行条件扫描。

时间点 Session1 Session2

id: 1

rows: 7

MySQL,DeadLock,故障排查

最佳的方法是添加column5和Column6的联合索引。

mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id

2   UPDATE TestTable SET Column2 = sysdate() Column4 = 0 AND Column5 = 47 AND Column6 = 'SEK 
执行成功,影响7行
     

32231892617   53454b\80000000007eea14   53454b\80000000007eeac4  
mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id blocking_trx_id, b.trx_mysql_thread_id blocking_thread, b.trx_query blocking_query FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id \G; *************************** 1. row *************************** waiting_trx_id: 103006 waiting_thread: 36 waiting_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK' blocking_trx_id: 103003 blocking_thread: 37 blocking_query: NULL *************************** 2. row *************************** waiting_trx_id: 421500433538672 waiting_thread: 39 waiting_query: select count(Column5) from TestTable where Column5 = 485 blocking_trx_id: 103006 blocking_thread: 36 blocking_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK' 2 rows in set, 1 warning (0.00 sec) mysql> select * from information_schema.innodb_lock_waits \G; *************************** 1. row *************************** requesting_trx_id: 103006 requested_lock_id: 103006:417:1493:859 blocking_trx_id: 103003 blocking_lock_id: 103003:417:1493:859 *************************** 2. row *************************** requesting_trx_id: 421500433538672 requested_lock_id: 421500433538672:417:749:2 blocking_trx_id: 103006 blocking_lock_id: 103006:417:749:2 2 rows in set, 1 warning (0.00 sec) mysql> select * from INNODB_LOCKS \G; *************************** 1. row *************************** lock_id: 103006:417:1493:859 lock_trx_id: 103006 lock_mode: X lock_type: RECORD lock_table: test.TestTable lock_index: idxColumn6 lock_space: 417 lock_page: 1493 lock_rec: 859 lock_data: 'SEK', 8262738 *************************** 2. row *************************** lock_id: 103003:417:1493:859 lock_trx_id: 103003 lock_mode: X lock_type: RECORD lock_table:test.TestTable lock_index: idxColumn6 lock_space: 417 lock_page: 1493 lock_rec: 859 lock_data: 'SEK', 8262738 *************************** 3. row *************************** lock_id: 421500433538672:417:749:2 lock_trx_id: 421500433538672 lock_mode: S lock_type: RECORD lock_table: test.TestTable lock_index: column5_index lock_space: 417 lock_page: 749 lock_rec: 2 lock_data: 485, 8317620 *************************** 4. row *************************** lock_id: 103006:417:749:2 lock_trx_id: 103006 lock_mode: X lock_type: RECORD lock_table: test.TestTable lock_index: column5_index lock_space: 417 lock_page: 749 lock_rec: 2 lock_data: 485, 8317620 4 rows in set, 1 warning (0.00 sec)

可以看到Session2,trx_id 103006阻塞了trx_id 421500433538672,而trx_id 421500433538672 requested_lock也正好是lock_data: 485, 8317620。由此可见Session2虽然别block了,但是还是获取到了Index column5_index相关的锁。被Block是因为intersect的原因,还需要idxColumn6的锁,至此思路已经清晰,对整个分配锁的信息简化一下,如下表格(请求到的锁用青色表示,需获取但未获取到的锁用红色表示):

possible_keys: column5_index,idx_column5_column6_Column1,idxColumn6

0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eeac4; asc

再先分析下(1) TRANSACTION,TRANSACTION 32231892617。

key_len: 8,9

【环境】

key: column5_index,idxColumn6

10:55左右删除索引后,报错没有再发生:

版本号:5.6.21

【解决方法】

时间序列 Session1 Session2
3       Begin;  

filtered: 100.00

根据以上初步分析,猜测应该就是intersect造成的,于是在测试环境模拟验证,开启2个session模拟死锁:

【初步分析】

等待的锁信息为:

0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eeac4; asc

于是可以画出的死锁表,两个资源相互依赖,造成死锁:

Extra: Using intersect(column5_index,idxColumn6); Using where

select_type: UPDATE

1   477 SEK      

mysql>desc UPDATE TestTable SET Column1=1, Column2 = sysdate(),Column3 = '025' Column4 = 0 AND Column5 = 477 AND Column6 = 'SEK' \G;

table: TestTable

接到监控报警,有一个线上的应用DeadLock报错,每15分钟会准时出现,报错统计如下图:

The Index Merge method is used to retrieve rows with several range scans and to merge their results into one. The merge can produce unions, intersections, or unions-of-intersections of its underlying scans. This access method merges index scans from a single table; it does not merge scans across multiple tables.

刘博:携程技术保障中心数据库高级经理,主要关注Sql server和Mysql的运维和故障处理。

让我们再看一下explain结果:

32231892482   53454b\80000000007eeac4   53454b\80000000007eea14  

可以看到 EXTRA 列:

1   Begin;      

隔离级别:REPEATABLE READ

2       485 SEK  
3   485 SEK   死锁发生  

type: index_merge

ref: NULL

【问题描述】

依据以上信息可以发现Session2虽然被Block了,但也获取了一些Session1在时间序列5时所需资源的X锁,可以再开启一个查询select count(Column5) from TestTable where Column5 = 485,设置SET TRANSACTION ISOLATION LEVEL SERIALIZABLE,去查询Column5 = 485的行,观察锁等待的信息:

相关文档:

TRANSACTION Hold Wait

partitions: NULL

【模拟与验证】

*************************** 1. row ***************************

我们环境当时的情况发现Column6的筛选度非常低,就删除了Column6的索引。

先分析下(2) TRANSACTION,TRANSACTION 32231892482。

mysql> show engine innodb status\G *** (1) TRANSACTION: TRANSACTION 102973, ACTIVE 11 sec starting index read mysql tables in use 3, locked 3 LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s) MySQL thread id 6, OS thread handle 140024996574976, query id 83 localhost us updating UPDATE TestTable SET column1 = 1, Column2 = sysdate(), Column3= '026' Column4 = 0 AND column5 = 485 AND column6 = 'SEK' *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_column6 of table test.TestTable trx id 102973 lock_mode X waiting Record lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007e1452; asc ~ R;; *** (2) TRANSACTION: TRANSACTION 102972, ACTIVE 26 sec starting index read mysql tables in use 3, locked 3 219 lock struct(s), heap size 24784, 2906 row lock(s), undo log entries 7 MySQL thread id 5, OS thread handle 140024996841216, query id 84 localhost us updating UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK' *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_Column6 of table test.TestTable trx id 102972 lock_mode X Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0 0: len 8; hex 73757072656d756d; asc supremum;; Record lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007e1452; asc ~ R;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 601 page no 89642 n bits 1000 index idx_column6 of table test.TestTable trx id 32231892482 lock_mode X locks rec but not gap waiting Record lock, heap no 38 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eea14; asc ~ ;;

大致一看,更新同一索引的同一行,应该是一个Block,报TimeOut的错才对,怎么会报DeadLock?

等待的锁信息为:

5   UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
执行成功
  ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction  
4       UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
被Blocking
 

相关热词: MYSQL

本站内容来源于网络,如有侵权请与我们联系,我们会及时删除,我们深感抱歉!
注:本站所有信息仅供用于网络技术学习参考,学习中请遵循相关法律法规!

本文地址: https://v30.fanwenzhu.com/sql/mysql/1902.shtml

最新文章
 这些文件如果在configure命 这些文件如果在configure命

时间:2021-01-22

说明在数据库崩溃时内存 说明在数据库崩溃时内存

时间:2021-01-22

破解极验(geetest)验证码 破解极验(geetest)验证码

时间:2021-01-22

今天这种代码阅读方法仍 今天这种代码阅读方法仍

时间:2021-01-22

 count(*) as cnt from sakila.fi count(*) as cnt from sakila.fi

时间:2021-01-22

 可能你注意到系统提示的 可能你注意到系统提示的

时间:2021-01-22

搭建环境与运行 搭建环境与运行

时间:2021-01-22

MySQL主从复制的常见拓扑 MySQL主从复制的常见拓扑

时间:2021-01-22

Copyright © www.juheyunku.com      关于 | 合作 | 声明 | 联系 | 更新 | 地图 | Tags

MySQL DeadLock故障排查全过程记录

2020-12-09 编辑:网络

0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eea14; asc

持有的锁信息为:

登录Mysql服务器查看日志:

可以看到485 SEK这两个资源形成了一个环状,最终发生死锁。

Using intersect(column5_index,idxColumn6)

从5.1开始,引入了 index merge 优化技术,对同一个表可以使用多个索引分别进行条件扫描。

时间点 Session1 Session2

id: 1

rows: 7

MySQL,DeadLock,故障排查

最佳的方法是添加column5和Column6的联合索引。

mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id

2   UPDATE TestTable SET Column2 = sysdate() Column4 = 0 AND Column5 = 47 AND Column6 = 'SEK 
执行成功,影响7行
     

32231892617   53454b\80000000007eea14   53454b\80000000007eeac4  
mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id blocking_trx_id, b.trx_mysql_thread_id blocking_thread, b.trx_query blocking_query FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id \G; *************************** 1. row *************************** waiting_trx_id: 103006 waiting_thread: 36 waiting_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK' blocking_trx_id: 103003 blocking_thread: 37 blocking_query: NULL *************************** 2. row *************************** waiting_trx_id: 421500433538672 waiting_thread: 39 waiting_query: select count(Column5) from TestTable where Column5 = 485 blocking_trx_id: 103006 blocking_thread: 36 blocking_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK' 2 rows in set, 1 warning (0.00 sec) mysql> select * from information_schema.innodb_lock_waits \G; *************************** 1. row *************************** requesting_trx_id: 103006 requested_lock_id: 103006:417:1493:859 blocking_trx_id: 103003 blocking_lock_id: 103003:417:1493:859 *************************** 2. row *************************** requesting_trx_id: 421500433538672 requested_lock_id: 421500433538672:417:749:2 blocking_trx_id: 103006 blocking_lock_id: 103006:417:749:2 2 rows in set, 1 warning (0.00 sec) mysql> select * from INNODB_LOCKS \G; *************************** 1. row *************************** lock_id: 103006:417:1493:859 lock_trx_id: 103006 lock_mode: X lock_type: RECORD lock_table: test.TestTable lock_index: idxColumn6 lock_space: 417 lock_page: 1493 lock_rec: 859 lock_data: 'SEK', 8262738 *************************** 2. row *************************** lock_id: 103003:417:1493:859 lock_trx_id: 103003 lock_mode: X lock_type: RECORD lock_table:test.TestTable lock_index: idxColumn6 lock_space: 417 lock_page: 1493 lock_rec: 859 lock_data: 'SEK', 8262738 *************************** 3. row *************************** lock_id: 421500433538672:417:749:2 lock_trx_id: 421500433538672 lock_mode: S lock_type: RECORD lock_table: test.TestTable lock_index: column5_index lock_space: 417 lock_page: 749 lock_rec: 2 lock_data: 485, 8317620 *************************** 4. row *************************** lock_id: 103006:417:749:2 lock_trx_id: 103006 lock_mode: X lock_type: RECORD lock_table: test.TestTable lock_index: column5_index lock_space: 417 lock_page: 749 lock_rec: 2 lock_data: 485, 8317620 4 rows in set, 1 warning (0.00 sec)

可以看到Session2,trx_id 103006阻塞了trx_id 421500433538672,而trx_id 421500433538672 requested_lock也正好是lock_data: 485, 8317620。由此可见Session2虽然别block了,但是还是获取到了Index column5_index相关的锁。被Block是因为intersect的原因,还需要idxColumn6的锁,至此思路已经清晰,对整个分配锁的信息简化一下,如下表格(请求到的锁用青色表示,需获取但未获取到的锁用红色表示):

possible_keys: column5_index,idx_column5_column6_Column1,idxColumn6

0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eeac4; asc

再先分析下(1) TRANSACTION,TRANSACTION 32231892617。

key_len: 8,9

【环境】

key: column5_index,idxColumn6

10:55左右删除索引后,报错没有再发生:

版本号:5.6.21

【解决方法】

时间序列 Session1 Session2
3       Begin;  

filtered: 100.00

根据以上初步分析,猜测应该就是intersect造成的,于是在测试环境模拟验证,开启2个session模拟死锁:

【初步分析】

等待的锁信息为:

0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eeac4; asc

于是可以画出的死锁表,两个资源相互依赖,造成死锁:

Extra: Using intersect(column5_index,idxColumn6); Using where

select_type: UPDATE

1   477 SEK      

mysql>desc UPDATE TestTable SET Column1=1, Column2 = sysdate(),Column3 = '025' Column4 = 0 AND Column5 = 477 AND Column6 = 'SEK' \G;

table: TestTable

接到监控报警,有一个线上的应用DeadLock报错,每15分钟会准时出现,报错统计如下图:

The Index Merge method is used to retrieve rows with several range scans and to merge their results into one. The merge can produce unions, intersections, or unions-of-intersections of its underlying scans. This access method merges index scans from a single table; it does not merge scans across multiple tables.

刘博:携程技术保障中心数据库高级经理,主要关注Sql server和Mysql的运维和故障处理。

让我们再看一下explain结果:

32231892482   53454b\80000000007eeac4   53454b\80000000007eea14  

可以看到 EXTRA 列:

1   Begin;      

隔离级别:REPEATABLE READ

2       485 SEK  
3   485 SEK   死锁发生  

type: index_merge

ref: NULL

【问题描述】

依据以上信息可以发现Session2虽然被Block了,但也获取了一些Session1在时间序列5时所需资源的X锁,可以再开启一个查询select count(Column5) from TestTable where Column5 = 485,设置SET TRANSACTION ISOLATION LEVEL SERIALIZABLE,去查询Column5 = 485的行,观察锁等待的信息:

相关文档:

TRANSACTION Hold Wait

partitions: NULL

【模拟与验证】

*************************** 1. row ***************************

我们环境当时的情况发现Column6的筛选度非常低,就删除了Column6的索引。

先分析下(2) TRANSACTION,TRANSACTION 32231892482。

mysql> show engine innodb status\G *** (1) TRANSACTION: TRANSACTION 102973, ACTIVE 11 sec starting index read mysql tables in use 3, locked 3 LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s) MySQL thread id 6, OS thread handle 140024996574976, query id 83 localhost us updating UPDATE TestTable SET column1 = 1, Column2 = sysdate(), Column3= '026' Column4 = 0 AND column5 = 485 AND column6 = 'SEK' *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_column6 of table test.TestTable trx id 102973 lock_mode X waiting Record lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007e1452; asc ~ R;; *** (2) TRANSACTION: TRANSACTION 102972, ACTIVE 26 sec starting index read mysql tables in use 3, locked 3 219 lock struct(s), heap size 24784, 2906 row lock(s), undo log entries 7 MySQL thread id 5, OS thread handle 140024996841216, query id 84 localhost us updating UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK' *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_Column6 of table test.TestTable trx id 102972 lock_mode X Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0 0: len 8; hex 73757072656d756d; asc supremum;; Record lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007e1452; asc ~ R;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 601 page no 89642 n bits 1000 index idx_column6 of table test.TestTable trx id 32231892482 lock_mode X locks rec but not gap waiting Record lock, heap no 38 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 3; hex 53454b; asc SEK;; 1: len 8; hex 80000000007eea14; asc ~ ;;

大致一看,更新同一索引的同一行,应该是一个Block,报TimeOut的错才对,怎么会报DeadLock?

等待的锁信息为:

5   UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
执行成功
  ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction  
4       UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
被Blocking
 

本站内容来源于网络,如有侵权请与我们联系,我们会及时删除,我们深感抱歉!
注:本站所有信息仅供学习参考!
本文地址为 https://v30.fanwenzhu.com/sql/mysql/1902.shtml

相关文章

风云图片

推荐阅读

返回mysql频道首页